**** dT 0.000
* top TEST ../../../../bin/varnishtest/tests/v00041.vtc starting
**** top extmacro def pkg_version=trunk
**** top extmacro def pkg_branch=trunk
**** top extmacro def pwd=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest
**** top extmacro def date(...)
**** top extmacro def string(...)
**** top extmacro def localhost=127.0.0.1
**** top extmacro def bad_backend=127.0.0.1:43173
**** top extmacro def listen_addr=127.0.0.1:0
**** top extmacro def bad_ip=192.0.2.255
**** top extmacro def topbuild=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub
**** top extmacro def topsrc=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/../..
**** top macro def testdir=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests
**** top macro def tmpdir=/home/linux1/VT/_vtest_tmp/vtc.737777.001b55ca
**** top macro def vtcid=vtc.737777.001b55ca
** top === varnishtest "Test priv_task"
* top VTEST Test priv_task
** top === feature !sanitizer
** top === server s1 {
** s1 Starting server
**** s1 macro def s1_addr=127.0.0.1
**** s1 macro def s1_port=40169
**** s1 macro def s1_sock=127.0.0.1:40169
* s1 Listen on 127.0.0.1:40169
** top === varnish v1 -arg "-p debug=+vclrel -p workspace_client=1m" -v...
**** dT 0.005
** s1 Started on 127.0.0.1:40169 (1 iterations)
**** dT 0.017
** v1 Launch
*** v1 CMD: cd ${pwd} && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.737777.001b55ca/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 40539' -P /home/linux1/VT/_vtest_tmp/vtc.737777.001b55ca/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -p debug=+vclrel -p workspace_client=1m
*** v1 CMD: cd /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.737777.001b55ca/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 40539' -P /home/linux1/VT/_vtest_tmp/vtc.737777.001b55ca/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -p debug=+vclrel -p workspace_client=1m
*** v1 PID: 737796
**** v1 macro def v1_pid=737796
**** v1 macro def v1_name=/home/linux1/VT/_vtest_tmp/vtc.737777.001b55ca/v1
**** dT 0.020
*** v1 debug|Info: Working directory not mounted on tmpfs partition
*** v1 debug|
**** dT 0.026
*** v1 debug|Debug: Version: varnish-trunk revision 92570c961a5742f9aa54437c4c88fb4e9a87a45a
*** v1 debug|Debug: Platform: Linux,4.18.0-553.50.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
*** v1 debug|200 329
*** v1 debug|-----------------------------
*** v1 debug|Varnish Cache CLI 1.0
*** v1 debug|-----------------------------
*** v1 debug|Linux,4.18.0-553.50.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
*** v1 debug|varnish-trunk revision 92570c961a5742f9aa54437c4c88fb4e9a87a45a
*** v1 debug|
*** v1 debug|Type 'help' for command list.
*** v1 debug|Type 'quit' to close CLI session.
*** v1 debug|Type 'start' to launch worker process.
*** v1 debug|
**** dT 0.128
**** v1 CLIPOLL 1 0x1 0x0 0x0
*** v1 CLI connection fd = 7
*** v1 CLI RX 107
**** v1 CLI RX|rztadygczdlzzfknmhojykadonhnxjjn
**** v1 CLI RX|
**** v1 CLI RX|Authentication required.
**** v1 CLI TX|auth 6f778132d8fc9a74a0c1491da07a2431488d89828e7fc39ef882602469013026
**** dT 0.134
*** v1 CLI RX 200
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Varnish Cache CLI 1.0
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Linux,4.18.0-553.50.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
**** v1 CLI RX|varnish-trunk revision 92570c961a5742f9aa54437c4c88fb4e9a87a45a
**** v1 CLI RX|
**** v1 CLI RX|Type 'help' for command list.
**** v1 CLI RX|Type 'quit' to close CLI session.
**** v1 CLI RX|Type 'start' to launch worker process.
**** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v1 CLI TX|vcl 4.1;
**** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "40169"; }
**** v1 CLI TX|
**** v1 CLI TX|
**** v1 CLI TX|\timport debug;
**** v1 CLI TX|\timport std;
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_init {
**** v1 CLI TX|\t\tnew objc = debug.obj();
**** v1 CLI TX|\t\tnew objb = debug.obj();
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub log_obj {
**** v1 CLI TX|\t\tstd.log("objc " + objc.test_priv_task());
**** v1 CLI TX|\t\tstd.log("objb " + objb.test_priv_task());
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_init {
**** v1 CLI TX|\t\tdebug.test_priv_task("something");
**** v1 CLI TX|\t\tdebug.test_priv_task("to remember");
**** v1 CLI TX|\t\tstd.log("func " + debug.test_priv_task());
**** v1 CLI TX|\t\tobjc.test_priv_task("initX");
**** v1 CLI TX|\t\tobjb.test_priv_task("initY");
**** v1 CLI TX|\t\tcall log_obj;
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_recv {
**** v1 CLI TX|\t\tif (req.url == "/perf") {
**** v1 CLI TX|\t\t\treturn (synth(200));
**** v1 CLI TX|\t\t}
**** v1 CLI TX|\t\tdebug.test_priv_task(req.url);
**** v1 CLI TX|\t\tset req.http.x0 = debug.test_priv_task();
**** v1 CLI TX|\t\tdebug.test_priv_task("bazz");
**** v1 CLI TX|\t\tcall log_obj;
**** v1 CLI TX|\t\tobjc.test_priv_task("c" + req.xid);
**** v1 CLI TX|\t\tif (req.url == "/pipe") {
**** v1 CLI TX|\t\t\treturn (pipe);
**** v1 CLI TX|\t\t}
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_pipe {
**** v1 CLI TX|\t\tcall log_obj;
**** v1 CLI TX|\t\tobjc.test_priv_task("p" + req.xid);
**** v1 CLI TX|
**** v1 CLI TX|\t\tdebug.test_priv_task(req.url);
**** v1 CLI TX|\t\tset req.http.x0 = debug.test_priv_task();
**** v1 CLI TX|\t\tdebug.test_priv_task("bazz");
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_synth {
**** v1 CLI TX|\t\tcall log_obj;
**** v1 CLI TX|\t\tobjc.test_priv_task("s" + req.xid);
**** v1 CLI TX|
**** v1 CLI TX|\t\tstd.log("discard 1000 " + debug.priv_perf(1000));
**** v1 CLI TX|\t\tstd.log("perf 1 " + debug.priv_perf(1));
**** v1 CLI TX|\t\tstd.log("perf 10 " + debug.priv_perf(10));
**** v1 CLI TX|\t\tstd.log("perf 100 " + debug.priv_perf(100));
**** v1 CLI TX|\t\t// std.log("perf 1000 " + debug.priv_perf(1000));
**** v1 CLI TX|\t\treturn (deliver);
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_deliver {
**** v1 CLI TX|\t\tcall log_obj;
**** v1 CLI TX|\t\tobjc.test_priv_task("d" + req.xid);
**** v1 CLI TX|
**** v1 CLI TX|\t\tset resp.http.x0 = req.http.x0;
**** v1 CLI TX|\t\tset resp.http.x1 = debug.test_priv_task();
**** v1 CLI TX|\t\tset resp.http.objc = objc.test_priv_task();
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_backend_fetch {
**** v1 CLI TX|\t\tcall log_obj;
**** v1 CLI TX|\t\tobjb.test_priv_task("f" + bereq.xid);
**** v1 CLI TX|
**** v1 CLI TX|\t\tdebug.test_priv_task("b");
**** v1 CLI TX|\t\tset bereq.http.bx0 = debug.test_priv_task(bereq.url);
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_backend_response {
**** v1 CLI TX|\t\tcall log_obj;
**** v1 CLI TX|\t\tobjb.test_priv_task("r" + bereq.xid);
**** v1 CLI TX|
**** v1 CLI TX|\t\tset beresp.http.bx0 = bereq.http.bx0;
**** v1 CLI TX|\t\tset beresp.http.bx1 = debug.test_priv_task("");
**** v1 CLI TX|\t\tset beresp.http.objb = objb.test_priv_task("");
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_fini {
**** v1 CLI TX|\t\tdebug.test_priv_task("cleaning");
**** v1 CLI TX|\t\tdebug.test_priv_task("up");
**** v1 CLI TX|\t\tstd.log("func " + debug.test_priv_task());
**** v1 CLI TX|\t\tstd.log("obj " + objc.test_priv_task());
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|
**** v1 CLI TX|%XJEIFLH|)Xspa8P
**** dT 0.241
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.347
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.449
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.553
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.658
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.760
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.863
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.967
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.073
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.176
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.277
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.377
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.480
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.585
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.690
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.792
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.895
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.995
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.098
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.200
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.306
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.406
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.506
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.607
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.709
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.810
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 2.911
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 3.011
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 3.114
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 3.170
*** v1 CLI RX 200
**** v1 CLI RX|VCL compiled.
**** v1 CLI TX|vcl.use vcl1
**** dT 3.219
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 3.320
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 3.421
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 3.521
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 3.621
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 3.723
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 3.825
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 3.927
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 4.027
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 4.127
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 4.154
*** v1 CLI RX 200
**** v1 CLI RX|VCL 'vcl1' now active
** v1 Start
**** v1 CLI TX|start
**** dT 4.167
*** v1 debug|Debug: Child (737809) Started
**** dT 4.261
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 4.358
*** v1 debug|Child launched OK
**** dT 4.423
*** v1 debug|Info: Child (737809) said Child starts
**** dT 4.492
**** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1745969566.964322/vgc.so 1auto
**** v1 vsl| 0 Debug - test_priv_task(0x3ff91dff030) = 0x254ed3c0 (new)
**** v1 vsl| 0 Debug - test_priv_task(0x3ff91dff030) = 0x254ed3c0 (update)
**** v1 vsl| 0 Debug - test_priv_task(0x3ff91dff030) = 0x254ed3c0 (exists)
**** v1 vsl| 0 VCL_Log - func something to remember
**** v1 vsl| 0 Debug - objc.priv_task() = 0x3ff91dff070 .priv = 0x3ff884089d4 ("initX") [new]
**** v1 vsl| 0 Debug - objb.priv_task() = 0x3ff91dff0b0 .priv = 0x3ff884089da ("initY") [new]
**** v1 vsl| 0 Debug - objc.priv_task() = 0x3ff91dff070 .priv = 0x3ff884089d4 ("initX")
**** v1 vsl| 0 VCL_Log - objc initX
**** v1 vsl| 0 Debug - objb.priv_task() = 0x3ff91dff0b0 .priv = 0x3ff884089da ("initY")
**** v1 vsl| 0 VCL_Log - objb initY
**** v1 vsl| 0 Debug - obj_priv_task_fini(0x3ff884089d4)
**** v1 vsl| 0 Debug - obj_priv_task_fini(0x3ff884089da)
**** v1 vsl| 0 Debug - priv_task_fini(0x254ed3c0)
**** v1 vsl| 0 Debug - vcl1: VCL_EVENT_WARM
**** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1745969566.964322/vgc.so" as "vcl1"
**** v1 vsl| 0 CLI - Rd vcl.use "vcl1"
**** v1 vsl| 0 CLI - Wr 200 0
**** v1 vsl| 0 CLI - Rd start
**** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:34853
**** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:34853
**** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:34853
**** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:34853
**** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:34853
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:34853
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:34853
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:34853
**** v1 vsl| 0 CLI - Wr 200 0
**** dT 4.938
*** v1 CLI RX 200
*** v1 wait-running
**** v1 CLI TX|status
**** dT 5.963
*** v1 CLI RX 200
**** v1 CLI RX|Child in state running
**** v1 CLI TX|debug.listen_address
**** dT 6.161
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 34853
**** v1 CLI TX|debug.xid 1000
**** dT 6.250
**** v1 vsl| 0 CLI - Rd debug.listen_address
**** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 34853
**** v1 vsl| 0 CLI - Rd debug.xid 1000
**** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1
**** dT 7.392
*** v1 CLI RX 200
**** v1 CLI RX|XID is 1000 chunk 1
**** v1 CLI TX|debug.listen_address
**** dT 7.395
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 34853
** v1 Listen on 127.0.0.1 34853
**** v1 macro def v1_addr=127.0.0.1
**** v1 macro def v1_port=34853
**** v1 macro def v1_sock=127.0.0.1:34853
**** v1 macro def v1_a0_addr=127.0.0.1
**** v1 macro def v1_a0_port=34853
**** v1 macro def v1_a0_sock=127.0.0.1:34853
** top === logexpect l0 -v v1 -g raw -d 1 -m -q "vxid == 0" {
** l0 === expect 0 0 CLI {^Rd vcl.load}
** l0 === expect 0 = Debug {^test_priv_task.*new.$}
** l0 === expect 0 = Debug {^test_priv_task.*update.$}
** l0 === expect 0 = Debug {^test_priv_task.*exists.$}
** l0 === expect 0 = VCL_Log {^func something to remember}
** l0 === expect 0 = Debug {^objc.priv_task.. = .*"initX". .new.}
** l0 === expect 0 = Debug {^objb.priv_task.. = .*"initY". .new.}
** l0 === expect 0 = Debug {^objc.priv_task.. = .*"initX"}
** l0 === expect 0 = VCL_Log {^objc initX}
** l0 === expect 0 = Debug {^objb.priv_task.. = .*"initY"}
** l0 === expect 0 = VCL_Log {^objb initY}
** l0 === expect ? = Debug {^priv_task_fini}
** l0 === expect ? = Debug {^obj_priv_task_fini}
** l0 === expect ? = Debug {^obj_priv_task_fini}
** l0 === expect 0 = Debug {^vcl1: VCL_EVENT_WARM}
** l0 === expect * = CLI {^Rd debug.xid}
** l0 === expect 0 = CLI {^Wr 200}
** l0 === expect 0 = CLI {^Rd debug.listen_address}
** l0 === expect 0 = CLI {^Wr 200}
** l0 === expect * = Debug {^vcl1: VCL_EVENT_COLD}
** l0 === expect 0 = CLI {^Wr 200 0 }
** l0 === expect 0 = CLI {^Rd vcl.discard vcl1}
** l0 === expect ? = Debug {^test_priv_task.*new.$}
** l0 === expect ? = Debug {^test_priv_task.*update.$}
** l0 === expect ? = Debug {^test_priv_task.*exists.$}
** l0 === expect ? = Debug {^objc.priv_task.. = NULL}
** l0 === expect ? = Debug {^priv_task_fini}
** l0 === expect ? = VCL_Log {^func cleaning up}
** l0 === expect ? = VCL_Log {^obj }
** l0 === expect 0 = CLI {^Wr 200 0 }
** top === logexpect l1001 -v v1 -g vxid -q "vxid == 1001" {
** l1001 === expect * 1001 VCL_call {^RECV}
** l1001 === expect 0 = Debug {^test_priv_task.*new.$}
** l1001 === expect 0 = Debug {^test_priv_task.*exists.$}
** l1001 === expect 0 = ReqHeader {^x0: /foobar}
** l1001 === expect 0 = Debug {^test_priv_task.*update.$}
** l1001 === expect 0 = Debug {^objc.priv_task.. = NULL}
** l1001 === expect 0 = VCL_Log {^objc }
** l1001 === expect 0 = Debug {^objb.priv_task.. = NULL}
** l1001 === expect 0 = VCL_Log {^objb }
** l1001 === expect 0 = Debug {^objc.priv_task.. =.*"c1001". .new.}
** l1001 === expect * = VCL_call {^DELIVER}
** l1001 === expect 0 = Debug {^objc.priv_task.. =.*"c1001".}
** l1001 === expect 0 = VCL_Log {^objc c1001}
** l1001 === expect 0 = Debug {^objb.priv_task.. = NULL}
** l1001 === expect 0 = VCL_Log {^objb }
** l1001 === expect 0 = Debug {^objc.priv_task.. =.*"d1001". .update....
** l1001 === expect 0 = RespHeader {^x0: /foobar}
** l1001 === expect 0 = Debug {^test_priv_task.*exists.$}
** l1001 === expect 0 = RespHeader {^x1: /foobar bazz}
** l1001 === expect 0 = Debug {^objc.priv_task.. =.*"d1001".}
** l1001 === expect 0 = RespHeader {^objc: d1001}
** l1001 === expect 0 = VCL_return {^deliver}
** l1001 === expect 9 = Timestamp {^Resp}
** l1001 === expect ? = Debug {^priv_task_fini}
** l1001 === expect ? = Debug {^obj_priv_task_fini}
** top === logexpect l1002 -v v1 -g vxid -q "vxid == 1002" {
** l1002 === expect * 1002 VCL_call {^BACKEND_FETCH}
** l1002 === expect 0 = Debug {^objc.priv_task.. = NULL}
** l1002 === expect 0 = VCL_Log {^objc }
** l1002 === expect 0 = Debug {^objb.priv_task.. = NULL}
** l1002 === expect 0 = VCL_Log {^objb }
** l1002 === expect 0 = Debug {^objb.priv_task.. =.*"f1002". .new.}
** l1002 === expect 0 = Debug {^test_priv_task.*new.$}
** l1002 === expect 0 = Debug {^test_priv_task.*update.$}
** l1002 === expect 0 = BereqHeader {^bx0: b /foobar}
** l1002 === expect 0 = VCL_return {^fetch}
** l1002 === expect * = VCL_call {^BACKEND_RESPONSE}
** l1002 === expect 0 = Debug {^objc.priv_task.. = NULL}
** l1002 === expect 0 = VCL_Log {^objc }
** l1002 === expect 0 = Debug {^objb.priv_task.. =.*"f1002".}
** l1002 === expect 0 = VCL_Log {^objb f1002}
** l1002 === expect 0 = Debug {^objb.priv_task.. =.*"r1002". .update....
** l1002 === expect 0 = BerespHeader {^bx0: b /foobar}
**** dT 7.396
** l1002 === expect 0 = Debug {^test_priv_task.*exists.$}
** l1002 === expect 0 = BerespHeader {^bx1: b /foobar}
** l1002 === expect 0 = Debug {^objb.priv_task.. =.*"r1002".}
** l1002 === expect 0 = BerespHeader {^objb: r1002}
** l1002 === expect 0 = VCL_return {^deliver}
** l1002 === expect 9 = Timestamp {^BerespBody}
** l1002 === expect ? = Debug {^priv_task_fini}
** l1002 === expect ? = Debug {^obj_priv_task_fini}
** top === logexpect l1006 -v v1 -g vxid -q "vxid == 1006" {
** l1006 === expect * 1006 VCL_call {^RECV}
** l1006 === expect 0 = Debug {^test_priv_task.*new.$}
** l1006 === expect 0 = Debug {^test_priv_task.*exists.$}
** l1006 === expect 0 = ReqHeader {^x0: /pipe}
** l1006 === expect 0 = Debug {^test_priv_task.*update.$}
** l1006 === expect 0 = Debug {^objc.priv_task.. = NULL}
** l1006 === expect 0 = VCL_Log {^objc }
** l1006 === expect 0 = Debug {^objb.priv_task.. = NULL}
** l1006 === expect 0 = VCL_Log {^objb }
** l1006 === expect 0 = Debug {^objc.priv_task.. =.*"c1006". .new.}
** l1006 === expect 0 = VCL_return {^pipe}
** l1006 === expect 0 = VCL_call {^HASH}
** l1006 === expect 0 = VCL_return {^lookup}
** l1006 === expect 0 = Link {^bereq 1007 pipe}
** l1006 === expect 0 = VCL_call {^PIPE}
** l1006 === expect 0 = Debug {^objc.priv_task.. =.*"c1006".}
** l1006 === expect 0 = VCL_Log {^objc c1006}
** l1006 === expect 0 = Debug {^objb.priv_task.. = NULL}
** l1006 === expect 0 = VCL_Log {^objb }
** l1006 === expect 0 = Debug {^objc.priv_task.. =.*"p1006". .update....
** l1006 === expect 0 = Debug {^test_priv_task.*update.$}
** l1006 === expect 0 = Debug {^test_priv_task.*exists.$}
** l1006 === expect 0 = ReqUnset {^x0: /pipe}
** l1006 === expect 0 = ReqHeader {^x0: /pipe bazz /pipe}
** l1006 === expect 0 = Debug {^test_priv_task.*update.$}
** l1006 === expect 0 = VCL_return {^pipe}
** l1006 === expect 4 = PipeAcct
** l1006 === expect ? = Debug {^priv_task_fini}
** l1006 === expect ? = Debug {^obj_priv_task_fini}
** top === client c1 {
** c1 Starting client
** c1 Waiting for client
** c1 Started on 127.0.0.1:34853 (1 iterations)
*** c1 Connect to 127.0.0.1:34853
*** c1 connected fd 37 from 127.0.0.1 55302 to 127.0.0.1:34853
** c1 === txreq -url /foobar
**** c1 txreq|GET /foobar HTTP/1.1\r
**** c1 txreq|Host: 127.0.0.1\r
**** c1 txreq|User-Agent: c1\r
**** c1 txreq|\r
** c1 === rxresp
**** l1001 begin|
**** l1001 qry | vxid == 1001
*** l1001 test | expect * 1001 VCL_call ^RECV
**** dT 7.399
**** l0 begin|
**** l0 qry | vxid == 0
*** l0 test | expect 0 0 CLI ^Rd vcl.load
**** l0 match| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1745969566.964322/vgc.so 1auto
*** l0 test | expect 0 = Debug ^test_priv_task.*new.$
**** l0 match| 0 Debug - test_priv_task(0x3ff91dff030) = 0x254ed3c0 (new)
*** l0 test | expect 0 = Debug ^test_priv_task.*update.$
**** l0 match| 0 Debug - test_priv_task(0x3ff91dff030) = 0x254ed3c0 (update)
*** l0 test | expect 0 = Debug ^test_priv_task.*exists.$
**** l0 match| 0 Debug - test_priv_task(0x3ff91dff030) = 0x254ed3c0 (exists)
*** l0 test | expect 0 = VCL_Log ^func something to remember
**** l0 match| 0 VCL_Log - func something to remember
*** l0 test | expect 0 = Debug ^objc.priv_task.. = .*\"initX\". .new.
**** l0 match| 0 Debug - objc.priv_task() = 0x3ff91dff070 .priv = 0x3ff884089d4 ("initX") [new]
*** l0 test | expect 0 = Debug ^objb.priv_task.. = .*\"initY\". .new.
**** l0 match| 0 Debug - objb.priv_task() = 0x3ff91dff0b0 .priv = 0x3ff884089da ("initY") [new]
*** l0 test | expect 0 = Debug ^objc.priv_task.. = .*\"initX\"
**** l0 match| 0 Debug - objc.priv_task() = 0x3ff91dff070 .priv = 0x3ff884089d4 ("initX")
*** l0 test | expect 0 = VCL_Log ^objc initX
**** l0 match| 0 VCL_Log - objc initX
*** l0 test | expect 0 = Debug ^objb.priv_task.. = .*\"initY\"
**** l0 match| 0 Debug - objb.priv_task() = 0x3ff91dff0b0 .priv = 0x3ff884089da ("initY")
*** l0 test | expect 0 = VCL_Log ^objb initY
**** l0 match| 0 VCL_Log - objb initY
*** l0 test | expect ? = Debug ^priv_task_fini
*** l0 alt | expect ? = Debug ^obj_priv_task_fini
**** l0 match| 0 Debug - obj_priv_task_fini(0x3ff884089d4)
*** l0 test | expect ? = Debug ^priv_task_fini
*** l0 alt | expect ? = Debug ^obj_priv_task_fini
**** l0 match| 0 Debug - obj_priv_task_fini(0x3ff884089da)
*** l0 test | expect ? = Debug ^priv_task_fini
**** l0 match| 0 Debug - priv_task_fini(0x254ed3c0)
*** l0 test | expect 0 = Debug ^vcl1: VCL_EVENT_WARM
**** l0 match| 0 Debug - vcl1: VCL_EVENT_WARM
*** l0 test | expect * = CLI ^Rd debug.xid
**** l0 miss | 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1745969566.964322/vgc.so" as "vcl1"
**** l0 miss | 0 CLI - Rd vcl.use "vcl1"
**** l0 miss | 0 CLI - Wr 200 0
**** l0 miss | 0 CLI - Rd start
**** l0 miss | 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:34853
**** l0 miss | 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:34853
**** l0 miss | 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:34853
**** l0 miss | 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:34853
**** l0 miss | 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:34853
**** l0 miss | 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:34853
**** l0 miss | 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:34853
**** l0 miss | 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:34853
**** l0 miss | 0 CLI - Wr 200 0
**** l0 miss | 0 CLI - Rd debug.listen_address
**** l0 miss | 0 CLI - Wr 200 19 a0 127.0.0.1 34853
**** l0 match| 0 CLI - Rd debug.xid 1000
*** l0 test | expect 0 = CLI ^Wr 200
**** l0 match| 0 CLI - Wr 200 19 XID is 1000 chunk 1
*** l0 test | expect 0 = CLI ^Rd debug.listen_address
**** l0 err | 0 CLI - Rd ping
---- l0 bad | expectation failed
**** l1002 begin|
**** l1002 qry | vxid == 1002
*** l1002 test | expect * 1002 VCL_call ^BACKEND_FETCH
---- l1002 bad | outstanding expectations
**** dT 7.400
*** s1 accepted fd 5 127.0.0.1 46046
*** s1 shutting fd 5
** s1 Ending
**** l1006 begin|
**** l1006 qry | vxid == 1006
*** l1006 test | expect * 1006 VCL_call ^RECV
---- l1006 bad | outstanding expectations
**** dT 7.406
---- l1001 bad | outstanding expectations
**** dT 7.407
**** c1 rxhdr|HTTP/1.1 503 Backend fetch failed\r
**** c1 rxhdr|Date: Tue, 29 Apr 2025 23:32:54 GMT\r
**** c1 rxhdr|Server: Varnish\r
**** c1 rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1 rxhdr|Retry-After: 5\r
**** c1 rxhdr|X-Varnish: 1001\r
**** c1 rxhdr|Age: 0\r
**** c1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c1 rxhdr|x0: /foobar\r
**** c1 rxhdr|x1: /foobar bazz\r
**** c1 rxhdr|objc: d1001\r
**** c1 rxhdr|Content-Length: 281\r
**** c1 rxhdr|Connection: keep-alive\r
**** c1 rxhdr|\r
**** c1 rxhdrlen = 290
**** c1 http[ 0] |HTTP/1.1
**** c1 http[ 1] |503
**** c1 http[ 2] |Backend fetch failed
**** c1 http[ 3] |Date: Tue, 29 Apr 2025 23:32:54 GMT
**** c1 http[ 4] |Server: Varnish
**** c1 http[ 5] |Content-Type: text/html; charset=utf-8
**** c1 http[ 6] |Retry-After: 5
**** c1 http[ 7] |X-Varnish: 1001
**** c1 http[ 8] |Age: 0
**** c1 http[ 9] |Via: 1.1 v1 (Varnish/trunk)
**** c1 http[10] |x0: /foobar
**** c1 http[11] |x1: /foobar bazz
**** c1 http[12] |objc: d1001
**** c1 http[13] |Content-Length: 281
**** c1 http[14] |Connection: keep-alive
**** c1 c-l|
**** c1 c-l|
**** c1 c-l|
**** c1 c-l| 503 Backend fetch failed
**** c1 c-l|
**** c1 c-l|
**** c1 c-l| Error 503 Backend fetch failed
**** c1 c-l| Backend fetch failed
**** c1 c-l| Guru Meditation:
**** c1 c-l| XID: 1002
**** c1 c-l|
**** c1 c-l| Varnish cache server
**** c1 c-l|
**** c1 c-l|
**** c1 bodylen = 281
*** c1 closing fd 37
** c1 Ending
* top RESETTING after ../../../../bin/varnishtest/tests/v00041.vtc
** l0 Waiting for logexp
** l1001 Waiting for logexp
** l1002 Waiting for logexp
** l1006 Waiting for logexp
** s1 Waiting for server (4/-1)
** v1 Wait
**** v1 CLI TX|panic.show
**** dT 7.450
*** v1 CLI RX 300
**** v1 CLI RX|Child has not panicked or panic has been cleared
**** dT 7.453
*** v1 debug|Info: manager stopping child
*** v1 debug|Debug: Stopping Child
**** dT 7.485
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1745969574 1.0
**** v1 vsl| 0 CLI - Rd debug.listen_address
**** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 34853
**** v1 vsl| 1000 Begin c sess 0 HTTP/1
**** v1 vsl| 1000 SessOpen c 127.0.0.1 55302 a0 127.0.0.1 34853 1745969574.224366 23
**** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:34853
**** v1 vsl| 1000 Debug c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:34853
**** v1 vsl| 1000 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:34853
**** v1 vsl| 1000 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:34853
**** v1 vsl| 1000 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:34853
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:34853
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:34853
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:34853
**** v1 vsl| 1000 Link c req 1001 rxreq
**** v1 vsl| 1002 Begin b bereq 1001 fetch
**** v1 vsl| 1002 VCL_use b vcl1
**** v1 vsl| 1002 Timestamp b Start: 1745969574.226352 0.000000 0.000000
**** v1 vsl| 1002 BereqMethod b GET
**** v1 vsl| 1002 BereqURL b /foobar
**** v1 vsl| 1002 BereqProtocol b HTTP/1.1
**** v1 vsl| 1002 BereqHeader b Host: 127.0.0.1
**** v1 vsl| 1002 BereqHeader b User-Agent: c1
**** v1 vsl| 1002 BereqHeader b X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1002 BereqHeader b Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1002 BereqHeader b x0: /foobar
**** v1 vsl| 1002 BereqHeader b Accept-Encoding: gzip
**** v1 vsl| 1002 BereqHeader b X-Varnish: 1002
**** v1 vsl| 1002 VCL_call b BACKEND_FETCH
**** v1 vsl| 1002 Debug b objc.priv_task() = NULL
**** v1 vsl| 1002 VCL_Log b objc
**** v1 vsl| 1002 Debug b objb.priv_task() = NULL
**** v1 vsl| 1002 VCL_Log b objb
**** v1 vsl| 1002 Debug b objb.priv_task() = 0x3ff5c0ddc60 .priv = 0x3ff5c0ddc38 ("f1002") [new]
**** v1 vsl| 1002 Debug b test_priv_task(0x3ff5c0ddca0) = 0x3ff4c000b60 (new)
**** v1 vsl| 1002 Debug b test_priv_task(0x3ff5c0ddca0) = 0x3ff4c000b60 (update)
**** v1 vsl| 1002 BereqHeader b bx0: b /foobar
**** v1 vsl| 1002 VCL_return b fetch
**** v1 vsl| 1002 Timestamp b Fetch: 1745969574.226398 0.000046 0.000046
**** v1 vsl| 1002 Timestamp b Connected: 1745969574.226444 0.000092 0.000046
**** v1 vsl| 1002 BackendOpen b 26 s1 127.0.0.1 40169 127.0.0.1 46046 connect
**** v1 vsl| 1002 Timestamp b Bereq: 1745969574.226471 0.000118 0.000026
**** v1 vsl| 1002 FetchError b HTC eof (Unexpected end of input)
**** v1 vsl| 1002 BackendClose b 26 s1 close RX_BAD
**** v1 vsl| 1002 Timestamp b Beresp: 1745969574.232311 0.005959 0.005840
**** v1 vsl| 1002 Timestamp b Error: 1745969574.232313 0.005961 0.000002
**** v1 vsl| 1002 BerespProtocol b HTTP/1.1
**** v1 vsl| 1002 BerespStatus b 503
**** v1 vsl| 1002 BerespReason b Backend fetch failed
**** v1 vsl| 1002 BerespHeader b Date: Tue, 29 Apr 2025 23:32:54 GMT
**** v1 vsl| 1002 BerespHeader b Server: Varnish
**** v1 vsl| 1002 VCL_call b BACKEND_ERROR
**** v1 vsl| 1002 BerespHeader b Content-Type: text/html; charset=utf-8
**** v1 vsl| 1002 BerespHeader b Retry-After: 5
**** v1 vsl| 1002 VCL_return b deliver
**** v1 vsl| 1002 Storage b malloc Transient
**** v1 vsl| 1002 Debug b obj_priv_task_fini(0x3ff5c0ddc38)
**** v1 vsl| 1002 Debug b priv_task_fini(0x3ff4c000b60)
**** v1 vsl| 1002 Length b 281
**** v1 vsl| 1002 BereqAcct b 183 0 183 0 0 0
**** v1 vsl| 1002 End b
**** v1 vsl| 1001 Begin c req 1000 rxreq
**** v1 vsl| 1001 Timestamp c Start: 1745969574.224409 0.000000 0.000000
**** v1 vsl| 1001 Timestamp c Req: 1745969574.224409 0.000000 0.000000
**** v1 vsl| 1001 VCL_use c vcl1
**** v1 vsl| 1001 ReqStart c 127.0.0.1 55302 a0
**** v1 vsl| 1001 ReqMethod c GET
**** v1 vsl| 1001 ReqURL c /foobar
**** v1 vsl| 1001 ReqProtocol c HTTP/1.1
**** v1 vsl| 1001 ReqHeader c Host: 127.0.0.1
**** v1 vsl| 1001 ReqHeader c User-Agent: c1
**** v1 vsl| 1001 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1001 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1001 VCL_call c RECV
**** v1 vsl| 1001 Debug c test_priv_task(0x3ff785ee160) = 0x3ff58000bb0 (new)
**** v1 vsl| 1001 Debug c test_priv_task(0x3ff785ee160) = 0x3ff58000bb0 (exists)
**** v1 vsl| 1001 ReqHeader c x0: /foobar
**** v1 vsl| 1001 Debug c test_priv_task(0x3ff785ee160) = 0x3ff58000bb0 (update)
**** v1 vsl| 1001 Debug c objc.priv_task() = NULL
**** v1 vsl| 1001 VCL_Log c objc
**** v1 vsl| 1001 Debug c objb.priv_task() = NULL
**** v1 vsl| 1001 VCL_Log c objb
**** v1 vsl| 1001 Debug c objc.priv_task() = 0x3ff785ee1c0 .priv = 0x3ff785ee198 ("c1001") [new]
**** v1 vsl| 1001 VCL_return c hash
**** v1 vsl| 1001 VCL_call c HASH
**** v1 vsl| 1001 VCL_return c lookup
**** v1 vsl| 1001 VCL_call c MISS
**** v1 vsl| 1001 VCL_return c fetch
**** v1 vsl| 1001 Link c bereq 1002 fetch
**** v1 vsl| 1001 Timestamp c Fetch: 1745969574.234576 0.010167 0.010167
**** v1 vsl| 1001 RespProtocol c HTTP/1.1
**** v1 vsl| 1001 RespStatus c 503
**** v1 vsl| 1001 RespReason c Backend fetch failed
**** v1 vsl| 1001 RespHeader c Date: Tue, 29 Apr 2025 23:32:54 GMT
**** v1 vsl| 1001 RespHeader c Server: Varnish
**** v1 vsl| 1001 RespHeader c Content-Type: text/html; charset=utf-8
**** v1 vsl| 1001 RespHeader c Retry-After: 5
**** v1 vsl| 1001 RespHeader c X-Varnish: 1001
**** v1 vsl| 1001 RespHeader c Age: 0
**** v1 vsl| 1001 RespHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1001 VCL_call c DELIVER
**** v1 vsl| 1001 Debug c objc.priv_task() = 0x3ff785ee1c0 .priv = 0x3ff785ee198 ("c1001")
**** v1 vsl| 1001 VCL_Log c objc c1001
**** v1 vsl| 1001 Debug c objb.priv_task() = NULL
**** v1 vsl| 1001 VCL_Log c objb
**** v1 vsl| 1001 Debug c objc.priv_task() = 0x3ff785ee1c0 .priv = 0x3ff785ee220 ("d1001") [update]
**** v1 vsl| 1001 RespHeader c x0: /foobar
**** v1 vsl| 1001 Debug c test_priv_task(0x3ff785ee160) = 0x3ff58000bb0 (exists)
**** v1 vsl| 1001 RespHeader c x1: /foobar bazz
**** v1 vsl| 1001 Debug c objc.priv_task() = 0x3ff785ee1c0 .priv = 0x3ff785ee220 ("d1001")
**** v1 vsl| 1001 RespHeader c objc: d1001
**** v1 vsl| 1001 VCL_return c deliver
**** v1 vsl| 1001 Timestamp c Process: 1745969574.234603 0.010193 0.000026
**** v1 vsl| 1001 Filters c
**** v1 vsl| 1001 RespHeader c Content-Length: 281
**** v1 vsl| 1001 RespHeader c Connection: keep-alive
**** v1 vsl| 1001 Timestamp c Resp: 1745969574.234626 0.010216 0.000023
**** v1 vsl| 1001 Debug c obj_priv_task_fini(0x3ff785ee220)
**** v1 vsl| 1001 Debug c priv_task_fini(0x3ff58000bb0)
**** v1 vsl| 1001 ReqAcct c 57 0 57 290 281 571
**** v1 vsl| 1001 End c
**** v1 vsl| 1000 SessClose c REM_CLOSE 0.016
**** v1 vsl| 1000 End c
**** v1 vsl| 0 CLI - EOF on CLI connection, worker stops
**** dT 7.552
*** v1 debug|Info: Child (737809) said Child dies
*** v1 debug|Info: Child (737809) ended
*** v1 debug|Debug: Child cleanup complete
*** v1 debug|Info: manager dies
**** dT 7.557
**** v1 STDOUT EOF
**** dT 7.589
** v1 WAIT4 pid=737796 status=0x0000 (user 0.310700 sys 0.036996)
* top TEST ../../../../bin/varnishtest/tests/v00041.vtc FAILED
# top TEST ../../../../bin/varnishtest/tests/v00041.vtc FAILED (7.594) exit=2
FAIL tests/v00041.vtc (exit status: 2)